Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Use tracing::Instrument in generated bindings to avoid holding spans across await points #9217

Merged
merged 2 commits into from
Sep 10, 2024

Conversation

swlynch99
Copy link
Contributor

@swlynch99 swlynch99 commented Sep 9, 2024

This PR fixes #9210.

Previously, if we had a WIT file with a function

async-fn: func();

then the generated code in add_to_linker_get_host would look like this (if tracing is enabled and the function is async)

inst.func_wrap_async(
    "my-func",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        wasmtime::component::__internal::Box::new(async move {
            let span = tracing::span!(
                tracing::Level::TRACE,
                "wit-bindgen import",
                module = "test",
                function = "my-func",
            );
            let _enter = span.enter();
            tracing::event!(tracing::Level::TRACE, "call");
            let host = &mut host_getter(caller.data_mut());
            let r = Host::my_func(host).await;
            tracing::event!(
                tracing::Level::TRACE,
                result = tracing::field::debug(&r),
                "return"
            );
            Ok(r)
        })
    },
)?;

This keeps the tracing span active, even when the resulting future is suspended. The end result is that other unrelated tokio tasks running on the same thread in the meantime will be shown as executing within the wit-bindgen import span.

This commit changes the codegen to instead generate

inst.func_wrap_async(
    "async-fn",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        use tracing::Instrument;

        let span = tracing::span!(
            tracing::Level::TRACE,
            "wit-bindgen import",
            module = "test",
            function = "async-fn",
        );
        wasmtime::component::__internal::Box::new(
            async move {
                tracing::event!(tracing::Level::TRACE, "call");
                let host = &mut host_getter(caller.data_mut());
                let r = Host::async_fn(host).await;
                tracing::event!(
                    tracing::Level::TRACE,
                    result = tracing::field::debug(&r),
                    "return"
                );
                Ok(r)
            }
            .instrument(span),
        )
    },
)?;

Here, tracing::Instrument takes care of entering the span when the future is polled and exiting it when it is suspended.

I have also manually verified that the codegen for sync functions remains exactly the same.

across await points

Previously, if we had a WIT file with a function

async-fn: func();

then the generated code in `add_to_linker_get_host` would look like
this (if tracing is enabled and the function is async)

inst.func_wrap_async(
    "my-func",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        wasmtime::component::__internal::Box::new(async move {
            let span = tracing::span!(
                tracing::Level::TRACE,
                "wit-bindgen import",
                module = "test",
                function = "my-func",
            );
            let _enter = span.enter();
            tracing::event!(tracing::Level::TRACE, "call");
            let host = &mut host_getter(caller.data_mut());
            let r = Host::my_func(host).await;
            tracing::event!(
                tracing::Level::TRACE,
                result = tracing::field::debug(&r),
                "return"
            );
            Ok(r)
        })
    },
)?;

This keeps the tracing span active, even when the resulting future is
suspended. The end result is that other unrelated tokio tasks running on
the same thread in the meantime will be shown as executing within the
`wit-bindgen import` span.

This commit changes the codegen to instead generate

inst.func_wrap_async(
    "async-fn",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        use tracing::Instrument;

        let span = tracing::span!(
            tracing::Level::TRACE,
            "wit-bindgen import",
            module = "test",
            function = "async-fn",
        );
        wasmtime::component::__internal::Box::new(
            async move {
                tracing::event!(tracing::Level::TRACE, "call");
                let host = &mut host_getter(caller.data_mut());
                let r = Host::async_fn(host).await;
                tracing::event!(
                    tracing::Level::TRACE,
                    result = tracing::field::debug(&r),
                    "return"
                );
                Ok(r)
            }
            .instrument(span),
        )
    },
)?;

Here, `tracing::Instrument` takes care of entering the span when the
future is polled and exiting it when it is suspended.

Fixes bytecodealliance#9210
Copy link
Member

@alexcrichton alexcrichton left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for this!

@alexcrichton alexcrichton added this pull request to the merge queue Sep 9, 2024
@github-merge-queue github-merge-queue bot removed this pull request from the merge queue due to no response for status checks Sep 10, 2024
@swlynch99
Copy link
Contributor Author

The macos wasmtime CI job seems to be stalled when running cargo fetch? I'm not sure what's up with that.

@pchickey pchickey added this pull request to the merge queue Sep 10, 2024
@pchickey
Copy link
Contributor

Sometimes runners just flake, lets try it again

Merged via the queue into bytecodealliance:main with commit 2b29e45 Sep 10, 2024
37 checks passed
@swlynch99 swlynch99 deleted the wit-bindgen-span-fix branch September 10, 2024 00:47
elliottt pushed a commit to elliottt/wasmtime that referenced this pull request Sep 16, 2024
…s across await points (bytecodealliance#9217)

* Use `tracing::Instrument` in generated bindings to avoid holding spans
across await points

Previously, if we had a WIT file with a function

async-fn: func();

then the generated code in `add_to_linker_get_host` would look like
this (if tracing is enabled and the function is async)

inst.func_wrap_async(
    "my-func",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        wasmtime::component::__internal::Box::new(async move {
            let span = tracing::span!(
                tracing::Level::TRACE,
                "wit-bindgen import",
                module = "test",
                function = "my-func",
            );
            let _enter = span.enter();
            tracing::event!(tracing::Level::TRACE, "call");
            let host = &mut host_getter(caller.data_mut());
            let r = Host::my_func(host).await;
            tracing::event!(
                tracing::Level::TRACE,
                result = tracing::field::debug(&r),
                "return"
            );
            Ok(r)
        })
    },
)?;

This keeps the tracing span active, even when the resulting future is
suspended. The end result is that other unrelated tokio tasks running on
the same thread in the meantime will be shown as executing within the
`wit-bindgen import` span.

This commit changes the codegen to instead generate

inst.func_wrap_async(
    "async-fn",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        use tracing::Instrument;

        let span = tracing::span!(
            tracing::Level::TRACE,
            "wit-bindgen import",
            module = "test",
            function = "async-fn",
        );
        wasmtime::component::__internal::Box::new(
            async move {
                tracing::event!(tracing::Level::TRACE, "call");
                let host = &mut host_getter(caller.data_mut());
                let r = Host::async_fn(host).await;
                tracing::event!(
                    tracing::Level::TRACE,
                    result = tracing::field::debug(&r),
                    "return"
                );
                Ok(r)
            }
            .instrument(span),
        )
    },
)?;

Here, `tracing::Instrument` takes care of entering the span when the
future is polled and exiting it when it is suspended.

Fixes bytecodealliance#9210

* Bless expanded macro outputs
alexcrichton pushed a commit that referenced this pull request Sep 16, 2024
* Use `tracing::Instrument` in generated bindings to avoid holding spans across await points (#9217)

* Use `tracing::Instrument` in generated bindings to avoid holding spans
across await points

Previously, if we had a WIT file with a function

async-fn: func();

then the generated code in `add_to_linker_get_host` would look like
this (if tracing is enabled and the function is async)

inst.func_wrap_async(
    "my-func",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        wasmtime::component::__internal::Box::new(async move {
            let span = tracing::span!(
                tracing::Level::TRACE,
                "wit-bindgen import",
                module = "test",
                function = "my-func",
            );
            let _enter = span.enter();
            tracing::event!(tracing::Level::TRACE, "call");
            let host = &mut host_getter(caller.data_mut());
            let r = Host::my_func(host).await;
            tracing::event!(
                tracing::Level::TRACE,
                result = tracing::field::debug(&r),
                "return"
            );
            Ok(r)
        })
    },
)?;

This keeps the tracing span active, even when the resulting future is
suspended. The end result is that other unrelated tokio tasks running on
the same thread in the meantime will be shown as executing within the
`wit-bindgen import` span.

This commit changes the codegen to instead generate

inst.func_wrap_async(
    "async-fn",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        use tracing::Instrument;

        let span = tracing::span!(
            tracing::Level::TRACE,
            "wit-bindgen import",
            module = "test",
            function = "async-fn",
        );
        wasmtime::component::__internal::Box::new(
            async move {
                tracing::event!(tracing::Level::TRACE, "call");
                let host = &mut host_getter(caller.data_mut());
                let r = Host::async_fn(host).await;
                tracing::event!(
                    tracing::Level::TRACE,
                    result = tracing::field::debug(&r),
                    "return"
                );
                Ok(r)
            }
            .instrument(span),
        )
    },
)?;

Here, `tracing::Instrument` takes care of entering the span when the
future is polled and exiting it when it is suspended.

Fixes #9210

* Bless expanded macro outputs

* Update the release notes

---------

Co-authored-by: Sean Lynch <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Tracing spans in code generated by wasmtime-wit-bindgen are entered incorrectly for async functions
3 participants